﻿//++
//
// Copyright (c) Microsoft Corporation.  All rights reserved.
//
// Module Name:
//
//    ERLogReporter.cs
//
// Abstract:
//    
//    Reporting tool to read and summarize the Enhanced Reminders ETL log files. 
//
//    Note: THIS CODE IS NOT TO BE SHIPPED.
//
//--

using System;
using System.Diagnostics;
using System.Collections.Generic;
using System.IO;
using Microsoft.OfficeCommunicationsServer.Applications.Common;
using Microsoft.OfficeCommunicationsServer.Applications.Common.UnitTests;

namespace Microsoft.EnhancedRemindersTools
{
    /// <summary>
    /// The component reporting an event.
    /// </summary>
    internal enum EventSource
    {
        Scheduler,
        Dispatcher,
        Unknown
    }

    /// <summary>
    /// Reads one or more ETL files and generates a system activity report.
    /// </summary>
    internal sealed class ERLogReporter
    {
        // Command line arguments.
        long _startTime = 0; // Represent start and end times by a FILETIME struct, initialized to null by default.
        long _endTime = 0;   
        List<string> _logfiles = new List<string>();
        string _dumpFileName = "Dump.txt"; // Hardcode for now.
        StreamWriter _dumpFile;
        string _summaryFileName = "Summary.txt"; // Hardcode for now.

        // General metrics
        int _fileCount = 0;
        int _eventCount = 0;

        // User data metrics.
        UserMetrics _userMetrics = new UserMetrics();

        // System usage metrics.
        SystemUsageMetrics _systemUsageMetrics = new SystemUsageMetrics();

        // System health metrics
        List<DateTime> _schedulerRestarts = new List<DateTime>();
        List<DateTime> _dispatcherRestarts = new List<DateTime>();
        List<DateTime> _exchangeWebServiceTimeouts = new List<DateTime>();
        List<DateTime> _ocsTimeouts = new List<DateTime>();
        List<string> _deliveryErrors = new List<string>();
        // $$TODO: Add categorized errors.

        /// <summary>
        /// Main entry point.
        /// </summary>
        static void Main(string[] args)
        {
            ERLogReporter logAnalyzer = new ERLogReporter();

            try
            {
                logAnalyzer.ParseCommandLine(args);
            }
            catch (ArgumentException exn)
            {
                Console.WriteLine("Invalid parameters: {0}\n", exn);
                logAnalyzer.ShowHelp();
                return;
            }

            try
            {
                logAnalyzer.ProcessFiles();
            }
            catch (InvalidOperationException exn)
            {
                Console.WriteLine("Error processing etl log files: " + exn.ToString());
                return;
            }
        }

        /// <summary>
        /// Parse the command line arguments.
        /// </summary>
        private void ParseCommandLine(string[] args)
        {
            if (args == null || args.Length == 0)
            {
                throw new ArgumentException();
            }
          
            for(int i = 0; i < args.Length; i++)
            {
                string arg = args[i];

                if (arg == "/?" || arg == "-help" || arg == "/help")
                {
                    throw new ArgumentException();
                }

                if (arg.Equals("-start", StringComparison.CurrentCultureIgnoreCase))
                {
                    _startTime = ParseStartEndTime(args, ++i);
                }
                else if (arg.Equals("-end", StringComparison.CurrentCultureIgnoreCase))
                {
                    _endTime = ParseStartEndTime(args, ++i);
                }
                else // Assume it's a logfile
                {
                    AddLogFiles(arg);
                }
            }

            if (_logfiles.Count == 0)
            {
                throw new ArgumentException("No logfiles specified");
            }
        }

        /// <summary>
        /// Convert a start/end DateTime string to a FILETIME.
        /// </summary>
        /// <param name="args">The command line args.</param>
        /// <param name="position">Position of the DateTime string to parse.</param>
        /// <returns></returns>
        private long ParseStartEndTime(string[] args, int position)
        {
            DateTime time = DateTime.Now;

            if (position >= args.Length ||
                !DateTime.TryParse(args[position], out time) ||
                _logfiles.Count > 0) // File args should occur after optional args.
            {
                throw new ArgumentException("Invalid start or end time");
            }

            return time.ToFileTime();
        }

        /// <summary>
        /// Output usage text.
        /// </summary>
        private void ShowHelp()
        {
            Console.WriteLine("USAGE:");
            Console.WriteLine("ERLogReporter [-start startDate] [-end endDate] file1.etl [file2.etl ...]");
            Console.WriteLine();
            Console.WriteLine("Writes summary to Summary.txt and dumps raw logs to Dump.txt");
            Console.WriteLine();
            Console.WriteLine("Examples:");
            Console.WriteLine("ERLogReporter *.etl");
            Console.WriteLine("ERLogReporter -start \"3/18/2008 1:00:00 PM\" file1.etl");
        }

        private void AddLogFiles(string filename)
        {
            Debug.Assert(!String.IsNullOrEmpty(filename), "filename");

            string current = Directory.GetCurrentDirectory();

            string dirname = Path.GetDirectoryName(filename);
            if (dirname == String.Empty)
            {
                dirname = current;
            }

            // Expands wildcards.
            string[] temp = Directory.GetFileSystemEntries(dirname, Path.GetFileName(filename));
            if (temp.Length == 0)
            {
                throw new ArgumentException(string.Format("Unable to locate input file '{0}'", filename));
            }

            _logfiles.AddRange(temp);
        }

        /// <summary>
        /// Iterate through the etl files.
        /// </summary>
        private void ProcessFiles()
        {
            // Open the file to dump raw event data.
            Debug.Assert(!String.IsNullOrEmpty(_dumpFileName), "_dumpFileName");
            
            _dumpFile = File.CreateText(_dumpFileName);
            _dumpFile.WriteLine("Time,Source,LogEntryType,ActivityId,Message,Error"); // Column headers.

            foreach (string logfile in _logfiles)
            {
                Console.WriteLine("Processing etl file: " + logfile);
                ProcessFile(logfile);
            }

            Console.WriteLine("ETL files processed: {0}", _fileCount);
            Console.WriteLine("Events processed: {0}", _eventCount);

            _dumpFile.Close();
            _dumpFile = null;

            GenerateReport();
        }

        /// <summary>
        /// Process a single etl file.
        /// </summary>
        /// <param name="logfileName"></param>
        private void ProcessFile(string logfileName)
        {
            Debug.Assert(!String.IsNullOrEmpty(logfileName), "logfileName");

            ++_fileCount;

            // Open the file
            NativeMethods.EVENT_TRACE_LOGFILE logfile = new NativeMethods.EVENT_TRACE_LOGFILE();
            logfile.LoggerName = null;
            logfile.LogfileName = logfileName;
            logfile.EventCallback = EventCallback;

            ulong handle = NativeMethods.OpenTrace(ref logfile);

            if (!NativeMethods.IsValidHandle(handle))
            {
                throw new InvalidOperationException("Error opening ETL file " + logfileName);
            }

            NativeMethods.ProcessTrace(new ulong[] { handle }, 
                                       /*handle array length*/1, 
                                       ref _startTime, 
                                       ref _endTime);

            NativeMethods.CloseTrace(handle);
        }

        /// <summary>
        /// Output a summary of the events found in the etl files to the summary file.
        /// </summary>
        private void GenerateReport()
        {
            Debug.Assert(!String.IsNullOrEmpty(_summaryFileName), "_summaryFileName");

            StreamWriter summaryFile = File.CreateText(_summaryFileName);

            if (_schedulerRestarts.Count == 0)
            {
                Console.WriteLine("Warning - no scheduler restarts found.  At least one restart is needed to capture user data");
            }

            // Write out the user data metrics.
            _userMetrics.WriteData(summaryFile);

            // Output system usage metrics.
            _systemUsageMetrics.WriteData(summaryFile);

            // Output system health metrics
            GenerateReportLine(summaryFile, "Scheduler restarted", _schedulerRestarts);
            GenerateReportLine(summaryFile, "Dispatcher restarted", _dispatcherRestarts);
            GenerateReportLine(summaryFile, "Exchange Web Service Timeout", _exchangeWebServiceTimeouts);
            GenerateReportLine(summaryFile, "OCS timeout", _ocsTimeouts);
            GenerateReportLine(summaryFile, "ER delivery errors", _deliveryErrors);

            summaryFile.Close();
        }

        /// <summary>
        /// Output an entry to the summary file.
        /// </summary>
        private static void GenerateReportLine<T>(StreamWriter summaryFile, string heading, IList<T> items)
        {
            Debug.Assert(summaryFile != null, "summaryFile");
            Debug.Assert(!String.IsNullOrEmpty(heading), "heading");
            Debug.Assert(items != null, "items");

            summaryFile.Write(heading);
            summaryFile.Write(' ');

            foreach (object obj in items)
            {
                summaryFile.Write(obj);
                summaryFile.Write(',');
            }

            summaryFile.WriteLine();
        }

        /// <summary>
        /// Event callback invoked for each event read from the etl files.
        /// </summary>
        /// <param name="eventTrace">The event.</param>
        private unsafe void EventCallback(ref NativeMethods.EVENT_TRACE eventTrace)
        {
            ++_eventCount;

            byte* pData = (byte*)eventTrace.MofData;
            int length = (int)eventTrace.MofLength;

            if (pData == null)
            {
                return;
            }

            using (UnmanagedMemoryStream stream = new UnmanagedMemoryStream(pData, length, length, FileAccess.Read))
            {
                BinaryReader reader = new BinaryReader(stream, System.Text.Encoding.Unicode);

                // The first 16 bytes should be the GUID associated with this event
                Guid guid = new Guid(reader.ReadBytes(16));

                // The remaining bytes should be the message string associated with this event
                char[] c = reader.ReadChars((int)(reader.BaseStream.Length - reader.BaseStream.Position - 1) / 2);

                EventSource source;
                string message;
                string error;
                if (TryParseEvent(c, out source, out message, out error))
                {
                    ProcessRecord(guid,
                                 (LogEntryType)eventTrace.Level,
                                  DateTime.FromFileTime(eventTrace.TimeStamp), 
                                  source, 
                                  message, 
                                  error);
                }
                else
                {
                    Console.WriteLine("Event failed to parse: " + c);
                }

                reader.Close();
            }
        }

        /// <summary>
        /// Parse the event XML message string to obtain event source, message and error fields.  For 
        /// simplicity and efficiency, this uses simple string matching on the target elements rather 
        /// than an XML reader.
        /// </summary>
        /// <param name="buffer">The event data logged by the Scheduler or Dispatcher.</param>
        /// <param name="eventSource">The component which logged the event.</param>
        /// <param name="message">The logged message string.</param>
        /// <param name="error">The logged error (or null if an error was not logged)</param>
        /// <returns>
        /// True if the event was parsed successfully; false otherwise.
        /// </returns>
        private static bool TryParseEvent(char[] buffer, out EventSource eventSource, out string message, out string error)
        {
            message = null;
            error = null;
            eventSource = EventSource.Unknown;

            if (buffer == null || buffer.Length == 0)
            {
                return false;
            }

            string eventData = new string(buffer);

            // Parse the source.
            string source = ExtractElement(eventData, "<source>", "</source>");
            if (source == null)
            {
                return false;
            }

            if (source.EndsWith("Scheduler"))
            {
                eventSource = EventSource.Scheduler;
            }
            else if (source.EndsWith("Dispatcher"))
            {
                eventSource = EventSource.Dispatcher;
            }
            else
            {
                eventSource = EventSource.Unknown;
            }

            // Parse the message string.
            message = ExtractElement(eventData, "<message>", "</message>");
            if (message == null)
            {
                return false;
            }

            // Parse the error field (if present).
            error = ExtractElement(eventData, "<error>", "</error>");

            return true;
        }

        /// <summary>
        /// Extract an XML element from the log XML message.
        /// </summary>
        /// <param name="message">The XML message to parse.</param>
        /// <param name="elementStart">The enclosing start element.</param>
        /// <param name="elementEnd">The terminating element.</param>
        /// <returns>
        /// The extracted element or null if not found.
        /// </returns>
        private static string ExtractElement(string message, string elementStart, string elementEnd)
        {
            Debug.Assert(!String.IsNullOrEmpty(message), "message");
            Debug.Assert(!String.IsNullOrEmpty(elementStart), "elementStart");
            Debug.Assert(!String.IsNullOrEmpty(elementEnd), "elementEnd");

            int start = message.IndexOf(elementStart);
            int end = message.IndexOf(elementEnd);

            if (start < 0 || end < 0 || start + elementStart.Length - 1 >= end)
            {
                return null;
            }

            start += elementStart.Length;

            return message.Substring(start, end - start);
        }

        /// <summary>
        /// Process an event to update the counters being tracked.
        /// </summary>
        /// <param name="logEntryType">The trace level (error, warning etc)</param>
        /// <param name="timestamp">The event timestamp.</param>
        /// <param name="source">The event source.</param>
        /// <param name="message">The event message.</param>
        /// <param name="error">Error message, or null if not an error.</param>
        private void ProcessRecord(Guid activityId, LogEntryType logEntryType, DateTime timestamp, EventSource source, string message, string error)
        {
            // Dump the event to the raw data file.
            Debug.Assert(_dumpFile != null, "_dumpFile");           
            
            _dumpFile.WriteLine("{0},{1},{2},{3},{4},{5}", 
                                timestamp.ToString(),
                                source.ToString(), 
                                logEntryType.ToString(),
                                activityId,
                                message, 
                                error);

            if (message != null)
            {
                if (message == "The service is starting")
                {
                    if (source == EventSource.Scheduler)
                    {
                        _schedulerRestarts.Add(timestamp);
                    }
                    else if (source == EventSource.Dispatcher)
                    {
                        _dispatcherRestarts.Add(timestamp);
                    }
                }       

                if (source == EventSource.Scheduler)
                {
                    // Update user channel and rule usage metrics if a user data message string.
                    _userMetrics.Update(activityId, message);

                    // Update system usage metrics from the notification result logged by the Scheduler.
                    _systemUsageMetrics.Update(timestamp, message);
                }

                // ER dispatcher errors
                const string matchString = "Received delivery confirmation for:";

                if (source == EventSource.Scheduler &&
                    message.Contains(matchString) &&
                    !message.Contains("Status: Success"))
                {
                    string deliveryError = "Delivery error " + timestamp.ToString() + message.Substring(matchString.Length + 2);
                    _deliveryErrors.Add(deliveryError);
                }
            }

            if (error != null && (logEntryType == LogEntryType.Warning || logEntryType == LogEntryType.Error))
            {
                // EWS timeouts
                if (source == EventSource.Scheduler && error.Contains("System.TimeoutException") && error.Contains("The HTTP request to"))
                {
                    _exchangeWebServiceTimeouts.Add(timestamp);
                }

                // OCS timeouts
                if (source == EventSource.Dispatcher && error.Contains("OCS timeout")) // $$TODO: Find the relevant message for this.
                {
                    _ocsTimeouts.Add(timestamp);
                }
            }
        }
    }
}